test: stop CLI-spawn timeouts from flaking the release gate#114
Merged
Conversation
Four tests failed intermittently under parallel load while passing in ~0.6s
idle. All the same cause: a spawn bound sized for an unloaded machine.
cli: franklin task tail reconciles stale queued tasks 5045ms (bound 5000)
cli: franklin task cancel <runId> kills running task 5841ms (bound 5000)
cli: franklin task wait reconciles stale queued tasks 5048ms (bound 5000)
franklin skills --json emits a parseable structure 8037ms (bound 8000)
The durations were the bound firing, not the work taking that long — the same
tests run in ~640ms when the machine is idle. `node dist/index.js` boots the
whole CLI (config load, MCP discovery, wallet init) before the subcommand runs,
and that startup balloons under concurrency.
Three things were wrong beyond the number:
1. The failures were undiagnosable. On timeout spawnSync returns status:null
with empty stderr, so `assert.equal(result.status, 0, result.stderr)` printed
"null !== 0" and named nothing. First time I hit this I could not tell what
had failed. assertCliExit() now says it exceeded the bound and that a loaded
machine is the likely cause.
2. skills.local.mjs had two bounds fighting: runCli defaulted to 8000ms while
the tests around it declared { timeout: 15_000 }, so the inner one always
won and the declared one never applied. Two call sites had already been
patched to timeoutMs: 15_000 individually — the usual sign that the default,
not the call site, is what's wrong.
3. One test told the CLI `--timeout 10000` under a 5000ms spawn bound, so the
harness would have killed the process before the behaviour under test could
finish. It only passed because the task goes 'lost' almost immediately.
Both files now use CLI_SPAWN_TIMEOUT_MS = 20_000, matching what test/local.mjs
already used for its other CLI-spawning tests ({ timeout: 20_000 }); 5s and 8s
were the outliers.
A flaky test in a release gate is worse than a slow one: it teaches you to wave
the next real failure past as "just that one again". Verified with two suites
running concurrently — the condition that produced the original failures —
636 pass on both.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Four tests failed intermittently under parallel load while passing in ~0.6s idle. Same cause in all four: a spawn bound sized for an unloaded machine.
cli: franklin task tail reconciles stale queued taskscli: franklin task cancel <runId> kills running taskcli: franklin task wait reconciles stale queued tasksfranklin skills --json emits a parseable structureThose durations are the bound firing, not the work. The same tests run in ~640ms idle.
node dist/index.jsboots the entire CLI — config load, MCP discovery, wallet init — before the subcommand executes, and that startup balloons under concurrency.Three things were wrong beyond the number
1. The failures were undiagnosable. On timeout
spawnSyncreturnsstatus: nullwith empty stderr, soassert.equal(result.status, 0, result.stderr.toString())printednull !== 0and named nothing. The first time I hit this I could not tell what had failed and nearly dismissed it.assertCliExit()now says the bound was exceeded and that a loaded machine is the likely cause, not broken code.2.
skills.local.mjshad two bounds fighting.runClidefaulted totimeoutMs = 8000while the tests around it declare{ timeout: 15_000 }— the inner bound always won, so the declared one never applied. Two call sites had already been patched totimeoutMs: 15_000individually, which is the usual sign that the default is what's wrong, not the call site.3. One test had its bounds inverted.
task wait ... --timeout 10000ran under a 5000ms spawn bound, so the harness would have killed the process before the behaviour under test could finish. It only passed because the task goeslostalmost immediately; a slower reconcile would have failed for reasons having nothing to do withtask wait.The fix
Both files use
CLI_SPAWN_TIMEOUT_MS = 20_000, matching whattest/local.mjsalready used for its other CLI-spawning tests ({ timeout: 20_000 }at lines 117, 127, 597, …). 5s and 8s were the outliers, not the new value.Why this matters more than four slow tests
A flaky test in a release gate is worse than a slow one — it trains you to wave the next real failure past as "just that one again". This session hit exactly that: a suite run went red mid-release, and the honest options were to investigate or to shrug. Had I shrugged, the flake would have been indistinguishable from a genuine regression.
Verification
Not just a clean run — two full suites executed concurrently, which is the condition that produced the original failures. 636 pass on both. Also 3 sequential runs, all green.